[DynamoDB] UserErrors が発生した場合に、その原因をCloudTrailで確認してみました

1 はじめに

IoT事業部の平内（SIN）です。

CloudWatchメトリクスで、UserErrorsのカウントが上がっているのを見つける事がありますが、こちらは、DynamoDB（または、DynamoDB Streams）へのリクエストにエラーがあったことを示しています。

下記のQAによると、実装等に何らかの問題ああって、ResourceNotFoundExceptionやValidationException などの例外が発生していることが原因とのことです。

Amazon DynamoDB テーブルに多数の UserErrors があるのはなぜですか?

しかし、メトリクスだけでは、テーブル名や、リクエストの内容までは、ちょっと分からないため、実装で例外が闇に葬られていたりすると、原因を見つけるのがちょっと難しくなる場合があります。

今回は、CloudTrailで「データイベント」を取得する証跡を作成して、メトリクスのタイムスタンプと照合することで、原因を特定する要領を確かめてみました。

2 Cloud Trail

CloudTrailで「データイベント」を取得する証跡を作成する要領は、以下の通りです。

• 新規に「証跡」を作成する

• ClodWatch Logsを有効にします

• 対象のイベントは「データイベント」とし、「DynamoDB」のすべてのイベントを記録するようにしました。

3 サンプル（Lambda）

動作確認のためにサンプル用にLambdaを作成しました。 テーブル（test-table）に１件書き込むだけの簡単なものです。

しかし、何らかの原因でテーブル名に誤りがあったりすると

table_name = "test-table-xxx"

ResourceNotFoundExceptionの例外が発生します。

Exception :An error occurred (ResourceNotFoundException) when calling the PutItem operation: Requested resource not found

また、アイテムの型を間違うとParameter validationとなります

item = {
    "id": {
        "N": 111
    }
}

Exception :Parameter validation failed:
Invalid type for parameter Item.id.N, value: 111, type: <class 'int'>, valid types: <class 'str'>

4 UserErrors

先のサンプルLambdaで、何回か例外を発生させてやると、UserErrorsメトリクスが観測されます。

ここで、統計を「合計」、期間を「１分」とする事で、分単位の「発生時間」と「件数」を得ることができます。ここでは、例として 「2022-06-19 00:03(UTC) 3件」をサンプルしてみました。

5 Tool

サンプルは、下記のようなプログラムで簡単に集めることもできます。

import boto3
import datetime

# 現在時間から、過去、指定した日数分を取得する
start_time = datetime.datetime.now() - datetime.timedelta(days=1)
end_time = datetime.datetime.now()

# メトリクス取得
client = boto3.client('cloudwatch')
response = client.get_metric_data(
    MetricDataQueries=[
        {
            'Id': 'm1',
            'MetricStat': {
                'Metric': {
                    'Namespace': 'AWS/DynamoDB',
                    'MetricName': 'UserErrors'
                },
                'Period': 60,
                'Stat': 'Sum',
                'Unit': 'Count'
            },
        },
    ],
    StartTime=start_time,
    EndTime=end_time
)
data = response['MetricDataResults'][0]
timestamps = data["Timestamps"]
values = data["Values"]

print("[DynamoDB.UserErrors 集計]")
print("発生時間(JST)\t件数")
for i in range(len(values)):
    # 確認しやすいように日本時間に変換
    jst = timestamps[i] + datetime.timedelta(hours=9)
    print("{}\t{}".format(jst.strftime('%m-%d %H:%M'), int(values[i])))

実行結果です。

% python3 index.py
[DynamoDB.UserErrors 集計]
発生時間(JST)   件数
06-19 09:30 1
06-19 09:26 1
06-19 09:25 2
06-19 09:05 2
06-19 09:03 3  <= 09:03 JST（00:03 UTC）に3件発生していることが確認できる
06-19 09:02 1
06-19 09:01 1
06-19 08:58 1
06-19 08:57 1
06-19 08:38 1

6 原因の調査

CloudWatch Logsに出力されたログをInsightで検索すると、サンプルしたタイムスタンプと件数が一致しているログを確認できると思います。

fields @timestamp, @message
|sort eventTime desc
|filter eventSource = 'dynamodb.amazonaws.com'
|display eventTime,eventName,requestParameters.tableName,requestParameters.key.id,errorCode,errorMessage
| limit 200

なお、証跡のログが、Insightで確認できるようになるまで、ちょっと時間がかかるので、リアルタイムは難しく、数分後に確認できるという感じになります。

また、同じ理由で、@timestampは、少しずれるので、@messageの中のeventTimeをsortして確認するとタイムスタンプが完全に一致できます。

CloudTrailのログを見つけることできれば、秒単位の実行時間、テーブル名、メソッド、エラーの原因や、Lambdaの関数名など、多くの情報を得ることができるので、原因調査には、大きな手がかりとなると思います。

7 最後に

今回は、CloudTrailで「データイベント」を取得する証跡を作成して、メトリクスのタイムスタンプと照合することで、原因を特定する要領を確かめてみました。

コストを上げないように、作業が終わったらCloudTrailの「証跡 （使用したS3やCloudWatch Logsも） 」は、削除しておいて下さい。

ちなみに、try catchで例外を抑制しても、UserErrorsは残ります。